**** dT 0.000 * top TEST ../../../../bin/vinyltest/vtest2/tests/a00005.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:42724 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub **** top extmacro def topsrc=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/../.. **** top macro def testdir=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/vtest2/tests **** top macro def tmpdir=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7 **** top macro def vtcid=vtc.94210.26749ea7 ** top === vtest "dual shared client HTTP transactions" * top VTEST dual shared client HTTP transactions ** top === server s1 { ** top === server s2 { ** top === server s1 -start ** s1 Starting server **** dT 0.001 **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=56738 **** s1 macro def s1_sock=127.0.0.1:56738 * s1 Listen on 127.0.0.1:56738 ** top === server s2 -start ** s2 Starting server **** s2 macro def s2_addr=127.0.0.1 **** s2 macro def s2_port=45342 **** s2 macro def s2_sock=127.0.0.1:45342 * s2 Listen on 127.0.0.1:45342 ** s1 Started on 127.0.0.1:56738 (1 iterations) ** top === client c1 -connect ${s1_sock} { ** top === client c1 -run ** c1 Starting client ** s2 Started on 127.0.0.1:45342 (1 iterations) ** c1 Waiting for client ** c1 Started on 127.0.0.1:56738 (1 iterations) *** c1 Connect to 127.0.0.1:56738 **** dT 0.002 *** c1 connected fd 7 from 127.0.0.1 53569 to 127.0.0.1:56738 ** c1 === txreq -req PUT -proto HTTP/1.0 -url /foo *** s1 accepted fd 5 127.0.0.1 53569 **** c1 txreq|PUT /foo HTTP/1.0\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp ** s1 === rxreq **** s1 rxhdr|PUT /foo HTTP/1.0\r **** s1 rxhdr|User-Agent: c1\r **** s1 rxhdr|\r **** s1 rxhdrlen = 37 **** s1 http[ 0] |PUT **** s1 http[ 1] |/foo **** s1 http[ 2] |HTTP/1.0 **** s1 http[ 3] |User-Agent: c1 **** s1 bodylen = 0 ** s1 === expect req.method == PUT **** s1 EXPECT req.method (PUT) == "PUT" match ** s1 === expect req.proto == HTTP/1.0 **** s1 EXPECT req.proto (HTTP/1.0) == "HTTP/1.0" match ** s1 === expect req.url == "/foo" **** s1 EXPECT req.url (/foo) == "/foo" match ** s1 === txresp -proto HTTP/1.2 -status 201 -reason Foo **** s1 txresp|HTTP/1.2 201 Foo\r **** s1 txresp|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r *** s1 shutting fd 5 (server run) ** s1 Ending **** c1 rxhdr|HTTP/1.2 201 Foo\r **** c1 rxhdr|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** c1 rxhdr|Server: s1\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|\r **** c1 rxhdrlen = 88 **** c1 http[ 0] |HTTP/1.2 **** c1 http[ 1] |201 **** c1 http[ 2] |Foo **** c1 http[ 3] |Date: Tue, 17 Mar 2026 00:24:55 GMT **** c1 http[ 4] |Server: s1 **** c1 http[ 5] |Content-Length: 0 **** c1 bodylen = 0 ** c1 === expect resp.proto == HTTP/1.2 **** c1 EXPECT resp.proto (HTTP/1.2) == "HTTP/1.2" match ** c1 === expect resp.status == 201 **** c1 EXPECT resp.status (201) == "201" match ** c1 === expect resp.reason == Foo **** c1 EXPECT resp.reason (Foo) == "Foo" match *** c1 closing fd 7 ** c1 Ending ** top === client c1 -connect ${s2_sock} { ** top === client c1 -run ** c1 Starting client **** dT 0.003 ** c1 Waiting for client ** c1 Started on 127.0.0.1:45342 (1 iterations) *** c1 Connect to 127.0.0.1:45342 *** c1 connected fd 5 from 127.0.0.1 50209 to 127.0.0.1:45342 *** s2 accepted fd 6 127.0.0.1 50209 ** c1 === txreq ** s2 === rxreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === rxresp **** s2 rxhdr|GET / HTTP/1.1\r **** s2 rxhdr|Host: 127.0.0.1\r **** s2 rxhdr|User-Agent: c1\r **** s2 rxhdr|\r **** s2 rxhdrlen = 51 **** s2 http[ 0] |GET **** s2 http[ 1] |/ **** s2 http[ 2] |HTTP/1.1 **** s2 http[ 3] |Host: 127.0.0.1 **** s2 http[ 4] |User-Agent: c1 **** s2 bodylen = 0 ** s2 === expect req.method == GET **** s2 EXPECT req.method (GET) == "GET" match ** s2 === expect req.proto == HTTP/1.1 **** s2 EXPECT req.proto (HTTP/1.1) == "HTTP/1.1" match ** s2 === expect req.url == "/" **** s2 EXPECT req.url (/) == "/" match ** s2 === txresp **** s2 txresp|HTTP/1.1 200 OK\r **** s2 txresp|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** s2 txresp|Server: s2\r **** s2 txresp|Content-Length: 0\r **** s2 txresp|\r *** s2 shutting fd 6 (server run) ** s2 Ending **** c1 rxhdr|HTTP/1.1 200 OK\r **** c1 rxhdr|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** c1 rxhdr|Server: s2\r **** c1 rxhdr|Content-Length: 0\r **** c1 rxhdr|\r **** c1 rxhdrlen = 87 **** c1 http[ 0] |HTTP/1.1 **** c1 http[ 1] |200 **** c1 http[ 2] |OK **** c1 http[ 3] |Date: Tue, 17 Mar 2026 00:24:55 GMT **** c1 http[ 4] |Server: s2 **** c1 http[ 5] |Content-Length: 0 **** c1 bodylen = 0 ** c1 === expect resp.proto == HTTP/1.1 **** c1 EXPECT resp.proto (HTTP/1.1) == "HTTP/1.1" match ** c1 === expect resp.status == 200 **** c1 EXPECT resp.status (200) == "200" match ** c1 === expect resp.reason == OK **** c1 EXPECT resp.reason (OK) == "OK" match *** c1 closing fd 5 ** c1 Ending ** top === server s1 -wait ** s1 Waiting for server (3/-1) ** top === server s2 -wait ** s2 Waiting for server (4/-1) ** top === server s3 -listen "${tmpdir}/s3.sock" { ** top === server s4 -listen "${tmpdir}/s4.sock" { ** top === server s3 -start ** s3 Starting server **** dT 0.004 **** s3 macro def s3_addr=0.0.0.0 **** s3 macro def s3_port=0 **** s3 macro def s3_sock=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock * s3 Listen on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock ** top === server s4 -start ** s4 Starting server **** s4 macro def s4_addr=0.0.0.0 **** s4 macro def s4_port=0 **** s4 macro def s4_sock=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock * s4 Listen on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock ** s3 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock (1 iterations) ** top === client c2 -connect ${s3_sock} { ** top === client c2 -run ** c2 Starting client ** s4 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock (1 iterations) ** c2 Waiting for client ** c2 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock (1 iterations) *** c2 Connect to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock *** c2 connected fd 9 to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s3.sock ** c2 === txreq -req PUT -proto HTTP/1.0 -url /foo **** c2 txreq|PUT /foo HTTP/1.0\r **** c2 txreq|User-Agent: c2\r **** c2 txreq|\r ** c2 === rxresp *** s3 accepted fd 7 0.0.0.0 0 ** s3 === rxreq **** s3 rxhdr|PUT /foo HTTP/1.0\r **** s3 rxhdr|User-Agent: c2\r **** s3 rxhdr|\r **** s3 rxhdrlen = 37 **** s3 http[ 0] |PUT **** s3 http[ 1] |/foo **** s3 http[ 2] |HTTP/1.0 **** s3 http[ 3] |User-Agent: c2 **** s3 bodylen = 0 ** s3 === expect req.method == PUT **** s3 EXPECT req.method (PUT) == "PUT" match ** s3 === expect req.proto == HTTP/1.0 **** s3 EXPECT req.proto (HTTP/1.0) == "HTTP/1.0" match ** s3 === expect req.url == "/foo" **** s3 EXPECT req.url (/foo) == "/foo" match ** s3 === txresp -proto HTTP/1.2 -status 201 -reason Foo **** s3 txresp|HTTP/1.2 201 Foo\r **** s3 txresp|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** s3 txresp|Server: s3\r **** s3 txresp|Content-Length: 0\r **** s3 txresp|\r *** s3 shutting fd 7 (server run) ** s3 Ending **** dT 0.005 **** c2 rxhdr|HTTP/1.2 201 Foo\r **** c2 rxhdr|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** c2 rxhdr|Server: s3\r **** c2 rxhdr|Content-Length: 0\r **** c2 rxhdr|\r **** c2 rxhdrlen = 88 **** c2 http[ 0] |HTTP/1.2 **** c2 http[ 1] |201 **** c2 http[ 2] |Foo **** c2 http[ 3] |Date: Tue, 17 Mar 2026 00:24:55 GMT **** c2 http[ 4] |Server: s3 **** c2 http[ 5] |Content-Length: 0 **** c2 bodylen = 0 ** c2 === expect resp.proto == HTTP/1.2 **** c2 EXPECT resp.proto (HTTP/1.2) == "HTTP/1.2" match ** c2 === expect resp.status == 201 **** c2 EXPECT resp.status (201) == "201" match ** c2 === expect resp.reason == Foo **** c2 EXPECT resp.reason (Foo) == "Foo" match *** c2 closing fd 9 ** c2 Ending ** top === client c2 -connect ${s4_sock} { ** top === client c2 -run ** c2 Starting client ** c2 Waiting for client ** c2 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock (1 iterations) *** c2 Connect to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock *** c2 connected fd 7 to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.94210.26749ea7/s4.sock ** c2 === txreq **** c2 txreq|GET / HTTP/1.1\r **** c2 txreq|Host: 127.0.0.1\r **** c2 txreq|User-Agent: c2\r **** c2 txreq|\r ** c2 === rxresp *** s4 accepted fd 8 0.0.0.0 0 ** s4 === rxreq **** s4 rxhdr|GET / HTTP/1.1\r **** s4 rxhdr|Host: 127.0.0.1\r **** s4 rxhdr|User-Agent: c2\r **** s4 rxhdr|\r **** s4 rxhdrlen = 51 **** s4 http[ 0] |GET **** s4 http[ 1] |/ **** s4 http[ 2] |HTTP/1.1 **** s4 http[ 3] |Host: 127.0.0.1 **** s4 http[ 4] |User-Agent: c2 **** s4 bodylen = 0 ** s4 === expect req.method == GET **** s4 EXPECT req.method (GET) == "GET" match ** s4 === expect req.proto == HTTP/1.1 **** s4 EXPECT req.proto (HTTP/1.1) == "HTTP/1.1" match ** s4 === expect req.url == "/" **** s4 EXPECT req.url (/) == "/" match ** s4 === txresp **** s4 txresp|HTTP/1.1 200 OK\r **** s4 txresp|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** s4 txresp|Server: s4\r **** s4 txresp|Content-Length: 0\r **** s4 txresp|\r *** s4 shutting fd 8 (server run) ** s4 Ending **** c2 rxhdr|HTTP/1.1 200 OK\r **** c2 rxhdr|Date: Tue, 17 Mar 2026 00:24:55 GMT\r **** c2 rxhdr|Server: s4\r **** c2 rxhdr|Content-Length: 0\r **** c2 rxhdr|\r **** c2 rxhdrlen = 87 **** c2 http[ 0] |HTTP/1.1 **** c2 http[ 1] |200 **** c2 http[ 2] |OK **** c2 http[ 3] |Date: Tue, 17 Mar 2026 00:24:55 GMT **** c2 http[ 4] |Server: s4 **** c2 http[ 5] |Content-Length: 0 **** c2 bodylen = 0 ** c2 === expect resp.proto == HTTP/1.1 **** c2 EXPECT resp.proto (HTTP/1.1) == "HTTP/1.1" match ** c2 === expect resp.status == 200 **** c2 EXPECT resp.status (200) == "200" match ** c2 === expect resp.reason == OK **** c2 EXPECT resp.reason (OK) == "OK" match *** c2 closing fd 7 ** c2 Ending ** top === server s3 -wait ** s3 Waiting for server (5/-1) ** top === server s4 -wait ** s4 Waiting for server (6/-1) * top RESETTING after ../../../../bin/vinyltest/vtest2/tests/a00005.vtc * top TEST ../../../../bin/vinyltest/vtest2/tests/a00005.vtc completed Assert error in cleaner_do(), ../../../../bin/vinyltest/vtest2/src/vtc_main.c line 240: Condition((system(buf)) == 0) not true. errno = 11 (Resource temporarily unavailable) ../../../../build-aux/test-driver: line 119: 94210: Abort FAIL vtest2/tests/a00005.vtc (exit status: 262)